[2024-05-28T06:45:30.000723Z] [info] +++ setup notes +++
[2024-05-28T06:45:30.000948Z] [info] Running on openqaworker22:19 (Linux 5.14.21-150500.55.65-default #1 SMP PREEMPT_DYNAMIC Thu May 23 04:57:11 UTC 2024 (a46829d) x86_64)
[2024-05-28T06:45:30.006150Z] [debug] Found ASSET_1, caching Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box
[2024-05-28T06:45:30.008816Z] [info] Downloading Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box, request #306445 sent to Cache Service
[2024-05-28T06:45:40.111496Z] [info] Download of Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box processed:
[info] [#306445] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306445] Downloading "Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" from "https://openqa.opensuse.org/tests/4226716/asset/other/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box"
[info] [#306445] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" has not changed, updating last use

[2024-05-28T06:45:40.113619Z] [debug] Found ASSET_2, caching Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box
[2024-05-28T06:45:40.116580Z] [info] Downloading Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box, request #306446 sent to Cache Service
[2024-05-28T06:45:50.239286Z] [info] Download of Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box processed:
[info] [#306446] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306446] Downloading "Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" from "https://openqa.opensuse.org/tests/4226716/asset/other/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box"
[info] [#306446] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" has not changed, updating last use

[2024-05-28T06:45:50.242074Z] [debug] Found ASSET_256, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256
[2024-05-28T06:45:50.245209Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256, request #306447 sent to Cache Service
[2024-05-28T06:45:55.310450Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256 processed:
[info] [#306447] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306447] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" from "https://openqa.opensuse.org/tests/4226716/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256"
[info] [#306447] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" has not changed, updating last use

[2024-05-28T06:45:55.312506Z] [debug] Found HDD_1, caching opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2
[2024-05-28T06:45:55.315138Z] [info] Downloading opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2, request #306449 sent to Cache Service
[2024-05-28T06:46:10.450406Z] [info] Download of opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2 processed:
[info] [#306449] Cache size of "/var/lib/openqa/cache" is 398 GiB, with limit 400 GiB
[info] [#306449] Downloading "opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2" from "https://openqa.opensuse.org/tests/4226716/asset/hdd/opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2"
[info] [#306449] Size of "/var/lib/openqa/cache/openqa.opensuse.org/opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2" is 1.4 GiB, with ETag ""66557d7d-59a80000""
[info] [#306449] Download of "/var/lib/openqa/cache/openqa.opensuse.org/opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2" successful (168 MiB/s), new cache size is 399 GiB

[2024-05-28T06:46:10.453306Z] [info] Rsync from 'rsync://openqa.opensuse.org/tests' to '/var/lib/openqa/cache/openqa.opensuse.org', request #306451 sent to Cache Service
[2024-05-28T06:46:20.552343Z] [info] Output of rsync:
[info] [#306451] Calling: rsync -avHP --timeout 1800 rsync://openqa.opensuse.org/tests/ --delete /var/lib/openqa/cache/openqa.opensuse.org/tests/
Try 1:
receiving incremental file list
obs/.git/
obs/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            483 100%  471.68kB/s    0:00:00 (xfr#1, ir-chk=1158/1178)
obs/.git/index

              0   0%    0.00kB/s    0:00:00  
          2,745 100%    2.62MB/s    0:00:00 (xfr#2, ir-chk=1153/1178)
obs/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
    392,171,776  63%  374.00MB/s    0:00:00  
    616,922,881 100%  374.74MB/s    0:00:01 (xfr#3, ir-chk=1133/1178)
obs/.git/objects/
obs/.git/refs/heads/
openqa/.git/
openqa/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            554 100%    0.60kB/s    0:00:00 (xfr#4, ir-chk=1167/1450)
openqa/.git/index

              0   0%    0.00kB/s    0:00:00  
          3,093 100%    3.37kB/s    0:00:00 (xfr#5, ir-chk=1162/1450)
openqa/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     10,389,345 100%   10.75MB/s    0:00:00 (xfr#6, ir-chk=1140/1450)
openqa/.git/objects/
openqa/.git/refs/heads/
openqa/products/openqa/needles/.git/
openqa/products/openqa/needles/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            259 100%    0.27kB/s    0:00:00 (xfr#7, ir-chk=1017/1607)
openqa/products/openqa/needles/.git/index

              0   0%    0.00kB/s    0:00:00  
         22,443 100%   23.67kB/s    0:00:00 (xfr#8, ir-chk=1012/1607)
openqa/products/openqa/needles/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     20,769,909 100%   20.15MB/s    0:00:00 (xfr#9, ir-chk=1004/1621)
openqa/products/openqa/needles/.git/objects/
openqa/products/openqa/needles/.git/refs/heads/
opensuse/.git/
opensuse/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
          7,264 100%    7.17kB/s    0:00:00 (xfr#10, ir-chk=1016/1702)
opensuse/.git/index

              0   0%    0.00kB/s    0:00:00  
        637,049 100%  627.14kB/s    0:00:00 (xfr#11, ir-chk=1011/1702)
opensuse/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
      2,766,984   9%    2.64MB/s    0:00:09  
     28,666,723 100%   25.65MB/s    0:00:01 (xfr#12, ir-chk=1005/1715)
opensuse/.git/objects/
opensuse/.git/refs/heads/
opensuse/products/opensuse/needles/.git/
opensuse/products/opensuse/needles/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            810 100%    1.85kB/s    0:00:00 (xfr#13, ir-chk=1014/21401)
opensuse/products/opensuse/needles/.git/index

              0   0%    0.00kB/s    0:00:00  
      1,574,039 100%    3.47MB/s    0:00:00 (xfr#14, ir-chk=1009/21401)
opensuse/products/opensuse/needles/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     10,997,584   8%   10.49MB/s    0:00:11  
    130,849,523 100%   95.99MB/s    0:00:01 (xfr#15, ir-chk=1009/21420)
opensuse/products/opensuse/needles/.git/objects/
opensuse/products/opensuse/needles/.git/refs/heads/

sent 347,801 bytes  received 1,406,592 bytes  269,906.62 bytes/sec
total size is 5,860,163,410  speedup is 3,340.28


[2024-05-28T06:46:20.552469Z] [info] Finished to rsync tests
[2024-05-28T06:46:20.557167Z] [debug] +++ worker notes +++
[37m[2024-05-28T06:46:20.889525Z] [debug] [pid:116896] Current version is 4.6.1716387241.58dd214 [interface v40][0m
[37m[2024-05-28T06:46:20.899049Z] [debug] [pid:116896] git hash in 'opensuse': 356dda665d7571846e3f46760c07806583dec84a[0m
[37m[2024-05-28T06:46:20.911763Z] [debug] [pid:116896] git url in 'opensuse': https://github.com/os-autoinst/os-autoinst-distri-opensuse.git[0m
[37m[2024-05-28T06:46:21.220232Z] [debug] [pid:116896] usingenv DESKTOP=textmode[0m
[37m[2024-05-28T06:46:21.220324Z] [debug] [pid:116896] usingenv DISTRI=opensuse[0m
[37m[2024-05-28T06:46:21.220364Z] [debug] [pid:116896] usingenv QEMUCPU=host[0m
[37m[2024-05-28T06:46:21.220402Z] [debug] [pid:116896] usingenv INSTLANG=en_US[0m
[37m[2024-05-28T06:46:21.220440Z] [debug] [pid:116896] usingenv DVD=1[0m
[37m[2024-05-28T06:46:21.220487Z] [debug] [pid:116896] usingenv ISO=[0m
[37m[2024-05-28T06:46:21.220525Z] [debug] [pid:116896] usingenv ISO_MAXSIZE=4700372992[0m
[37m[2024-05-28T06:46:21.222878Z] [debug] [pid:116896] parse_vars (variables parsed from YAML schedule):[0m
[37m[2024-05-28T06:46:21.223377Z] [debug] [pid:116896] ---
  BOOT_TO_SNAPSHOT: 1
  [0m
[37m[2024-05-28T06:46:21.223637Z] [debug] [pid:116896] ---
  - boot/boot_to_desktop
  - installation/boot_into_snapshot
  [0m
[37m[2024-05-28T06:46:21.223699Z] [debug] [pid:116896] parse_test_suite_data (data parsed from YAML test_data):[0m
[37m[2024-05-28T06:46:21.223795Z] [debug] [pid:116896] --- {}
  [0m
[37m[2024-05-28T06:46:21.225275Z] [debug] [pid:116896] scheduling boot_to_desktop tests/boot/boot_to_desktop.pm[0m
[37m[2024-05-28T06:46:21.225985Z] [debug] [pid:116896] scheduling boot_into_snapshot tests/installation/boot_into_snapshot.pm[0m
[2024-05-28T06:46:21.232581Z] [info] [pid:117033] cmdsrv: daemon reachable under http://*:20193/XdWpZabLnV6ZUo4b/
[2024-05-28T06:46:21.234068Z] [info] [pid:117033] Listening at "http://[::]:20193"
Web application available at http://[::]:20193
[37m[2024-05-28T06:46:21.237406Z] [debug] [pid:116896] git hash in 'opensuse/products/opensuse/needles': 9c264ee66e0366e6bfd7b2a1d219ca52ddb44beb[0m
[37m[2024-05-28T06:46:21.254805Z] [debug] [pid:116896] git url in 'opensuse/products/opensuse/needles': git@github.com:os-autoinst/os-autoinst-needles-opensuse.git[0m
[37m[2024-05-28T06:46:21.254955Z] [debug] [pid:116896] init needles from opensuse/products/opensuse/needles[0m
[37m[2024-05-28T06:46:21.978842Z] [debug] [pid:116896] loaded 7144 needles[0m
[37m[2024-05-28T06:46:22.166626Z] [debug] [pid:116896] 116896: channel_out 16, channel_in 15[0m
[37m[2024-05-28T06:46:22.223755Z] [debug] [pid:117233] 117233: cmdpipe 14, rsppipe 17[0m
[37m[2024-05-28T06:46:22.223933Z] [debug] [pid:117233] started mgmt loop with pid 117233[0m
[37m[2024-05-28T06:46:22.284267Z] [debug] [pid:117233] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libvpx-vp9 -crf 35 -b:v 1500k -cpu-used 1 'video.webm'[0m
[37m[2024-05-28T06:46:22.349346Z] [debug] [pid:117233] qemu version detected: 7.1.0[0m
[37m[2024-05-28T06:46:22.351092Z] [debug] [pid:117233] running `/usr/bin/chattr +C /var/lib/openqa/pool/19/raid`[0m
[37m[2024-05-28T06:46:22.365267Z] [debug] [pid:117233] Command `/usr/bin/chattr +C /var/lib/openqa/pool/19/raid` terminated with 1
  /usr/bin/chattr: Operation not supported while setting flags on /var/lib/openqa/pool/19/raid[0m
[37m[2024-05-28T06:46:22.365353Z] [debug] [pid:117233] Configuring storage controllers and block devices[0m
[37m[2024-05-28T06:46:22.365845Z] [debug] [pid:117233] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/19/opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2`[0m
[37m[2024-05-28T06:46:22.402702Z] [debug] [pid:117233] Initializing block device images[0m
[37m[2024-05-28T06:46:22.402926Z] [debug] [pid:117233] running `/usr/bin/qemu-img create -f qcow2 -F qcow2 -b /var/lib/openqa/pool/19/opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2 /var/lib/openqa/pool/19/raid/hd0-overlay0 32212254720`[0m
[37m[2024-05-28T06:46:22.448146Z] [debug] [pid:117233] Formatting '/var/lib/openqa/pool/19/raid/hd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=32212254720 backing_file=/var/lib/openqa/pool/19/opensuse-Tumbleweed-x86_64-20240527-textmode@64bit.qcow2 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T06:46:22.448239Z] [debug] [pid:117233] init_blockdev_images: Finished creating block devices[0m
[37m[2024-05-28T06:46:22.449182Z] [debug] [pid:117233] starting: /usr/bin/qemu-system-x86_64 -device VGA,edid=on,xres=1024,yres=768 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.fdtypeA=none -m 1536 -cpu host -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot order=c -device qemu-xhci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :109,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay0-file,filename=/var/lib/openqa/pool/19/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0-overlay0,bootindex=0,serial=hd0[0m
[37m[2024-05-28T06:46:22.455093Z] [debug] [pid:117233] Waiting for 0 attempts[0m
[37m[2024-05-28T06:46:23.455617Z] [debug] [pid:117233] Waiting for 1 attempts[0m
[37m[2024-05-28T06:46:24.455983Z] [debug] [pid:117233] Finished after 2 attempts[0m
[37m[2024-05-28T06:46:24.468951Z] [debug] [pid:117233] Establishing VNC connection to localhost:6009[0m
[37m[2024-05-28T06:46:24.471357Z] [debug] [pid:117233] pointer type 0 0 640 480 -257[0m
[37m[2024-05-28T06:46:24.471428Z] [debug] [pid:117233] led state 0 1 1 -261[0m
[37m[2024-05-28T06:46:24.525530Z] [debug] [pid:117233] Start CPU[0m
[37m[2024-05-28T06:46:24.525699Z] [debug] [pid:117233] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"60808","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6009","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":469462,"seconds":1716878784}}[0m
[37m[2024-05-28T06:46:24.525786Z] [debug] [pid:117233] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"60808","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6009","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":470562,"seconds":1716878784}}[0m
[37m[2024-05-28T06:46:24.525862Z] [debug] [pid:117233] EVENT {"event":"RESUME","timestamp":{"microseconds":525781,"seconds":1716878784}}[0m
GOT GO

[37m[2024-05-28T06:46:24.530123Z] [debug] [pid:117233] QEMU: QEMU emulator version 7.1.0 (SUSE Linux Enterprise 15)[0m
[37m[2024-05-28T06:46:24.530172Z] [debug] [pid:117233] QEMU: Copyright (c) 2003-2022 Fabrice Bellard and the QEMU Project developers[0m
[37m[2024-05-28T06:46:24.532684Z] [debug] [pid:117043] Snapshots are supported[0m
[1;34m[2024-05-28T06:46:24.533503Z] [debug] [pid:117043] ||| starting boot_to_desktop tests/boot/boot_to_desktop.pm[0m
[2024-05-28T06:46:24.535968Z] [debug] [pid:117043] tests/boot/boot_to_desktop.pm:53 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:902 called opensusebasetest::handle_grub -> lib/opensusebasetest.pm:687 called opensusebasetest::wait_grub -> lib/opensusebasetest.pm:439 called testapi::assert_screen
[2024-05-28T06:46:24.536261Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch=[
    "grub2"
  ], timeout=200)
[31m[2024-05-28T06:46:26.270389Z] [warn] [pid:117233] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.74 seconds for 72 candidate needles - make your needles more specific[0m
[37m[2024-05-28T06:46:26.270479Z] [debug] [pid:117233] no match: 199.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
Input #0, image2pipe, from 'pipe:':
  Duration: N/A, bitrate: N/A
  Stream #0:0: Video: ppm, rgb24, 1024x768, 24 fps, 24 tbr, 24 tbn, 24 tbc
Stream mapping:
  Stream #0:0 -> #0:0 (ppm (native) -> vp9 (libvpx-vp9))
[libvpx-vp9 @ 0x55796dddc900] v1.11.0
Output #0, webm, to 'video.webm':
  Metadata:
    encoder         : Lavf58.76.100
  Stream #0:0: Video: vp9, yuv420p(tv, progressive), 1024x768, q=2-31, 1500 kb/s, 24 fps, 1k tbn
    Metadata:
      encoder         : Lavc58.134.100 libvpx-vp9
    Side data:
      cpb: bitrate max/min/avg: 0/0/0 buffer size: 0 vbv_delay: N/A
[32m[2024-05-28T06:46:26.913953Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190303, similarity 1.00 @ 11/147[0m
[2024-05-28T06:46:26.914574Z] [debug] [pid:117043] tests/boot/boot_to_desktop.pm:53 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:902 called opensusebasetest::handle_grub -> lib/opensusebasetest.pm:702 called opensusebasetest::grub_select -> lib/opensusebasetest.pm:634 called testapi::send_key
[2024-05-28T06:46:26.914688Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:46:27.184356Z] [debug] [pid:117043] tests/boot/boot_to_desktop.pm:53 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:926 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:782 called opensusebasetest::wait_boot_textmode -> lib/opensusebasetest.pm:718 called testapi::assert_screen
[2024-05-28T06:46:27.184530Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch=[
    "linux-login",
    "emergency-shell",
    "emergency-mode"
  ], timeout=500)
[37m[2024-05-28T06:46:27.617099Z] [debug] [pid:117233] no match: 499.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:28.589378Z] [debug] [pid:117233] no match: 498.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:29.530458Z] [debug] [pid:117233] no change: 497.6s[0m
[37m[2024-05-28T06:46:29.568802Z] [debug] [pid:117233] no match: 497.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:30.531528Z] [debug] [pid:117233] no change: 496.6s[0m
[37m[2024-05-28T06:46:30.571426Z] [debug] [pid:117233] no match: 496.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:30.876686Z] [debug] [pid:117233] pointer type 1 0 800 600 -257[0m
[31m[2024-05-28T06:46:32.161332Z] [warn] [pid:117233] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.63 seconds for 12 candidate needles - make your needles more specific[0m
[37m[2024-05-28T06:46:32.161421Z] [debug] [pid:117233] no match: 495.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:32.574756Z] [debug] [pid:117233] no match: 494.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:33.572937Z] [debug] [pid:117233] no match: 493.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:34.606367Z] [debug] [pid:117233] no match: 492.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:35.535946Z] [debug] [pid:117233] no change: 491.6s[0m
[37m[2024-05-28T06:46:35.605647Z] [debug] [pid:117233] no match: 491.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T06:46:39.716621Z] [warn] [pid:117233] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 3.18 seconds for 12 candidate needles - make your needles more specific[0m
[37m[2024-05-28T06:46:39.716710Z] [debug] [pid:117233] no match: 490.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:46:39.760969Z] [debug] [pid:117233] no match: 487.4s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[32m[2024-05-28T06:46:40.815032Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found linux-login-20200525, similarity 1.00 @ 72/749[0m
[1;34m[2024-05-28T06:46:40.823899Z] [debug] [pid:117043] ||| finished boot_to_desktop boot (runtime: 16 s)[0m
[37m[2024-05-28T06:46:40.825110Z] [debug] [pid:117043] Creating a VM snapshot lastgood[0m
[37m[2024-05-28T06:46:40.825520Z] [debug] [pid:117233] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[3]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":226701,"seconds":1716878797}}[0m
[37m[2024-05-28T06:46:40.825762Z] [debug] [pid:117233] Saving snapshot (Current VM state is running)[0m
[37m[2024-05-28T06:46:40.844838Z] [debug] [pid:117233] EVENT {"event":"STOP","timestamp":{"microseconds":844751,"seconds":1716878800}}[0m
[37m[2024-05-28T06:46:40.849925Z] [debug] [pid:117233] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/19/raid/hd0-overlay1','snapshot-node-name' => 'hd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T06:46:40.853022Z] [debug] [pid:117233] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":852938,"seconds":1716878800}}[0m
[37m[2024-05-28T06:46:41.353443Z] [debug] [pid:117233] EVENT {"data":{"pass":1},"event":"MIGRATION_PASS","timestamp":{"microseconds":864766,"seconds":1716878800}}[0m
[37m[2024-05-28T06:46:41.353551Z] [debug] [pid:117233] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":864852,"seconds":1716878800}}[0m
[37m[2024-05-28T06:46:41.353698Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:41.353745Z] [debug] [pid:117233] Migrating remaining bytes:   	1606008832[0m
[37m[2024-05-28T06:46:41.854333Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:41.854401Z] [debug] [pid:117233] Migrating remaining bytes:   	1580408832[0m
[37m[2024-05-28T06:46:42.354891Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:42.354958Z] [debug] [pid:117233] Migrating remaining bytes:   	1557868544[0m
[37m[2024-05-28T06:46:42.855460Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:42.855529Z] [debug] [pid:117233] Migrating remaining bytes:   	1526964224[0m
[37m[2024-05-28T06:46:43.356083Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:43.356145Z] [debug] [pid:117233] Migrating remaining bytes:   	1511186432[0m
[37m[2024-05-28T06:46:43.856797Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:43.856869Z] [debug] [pid:117233] Migrating remaining bytes:   	1493434368[0m
[37m[2024-05-28T06:46:44.357396Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:44.357467Z] [debug] [pid:117233] Migrating remaining bytes:   	1474273280[0m
[37m[2024-05-28T06:46:44.857973Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:44.858037Z] [debug] [pid:117233] Migrating remaining bytes:   	1456467968[0m
[37m[2024-05-28T06:46:45.358655Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:45.358749Z] [debug] [pid:117233] Migrating remaining bytes:   	1439092736[0m
[37m[2024-05-28T06:46:45.859396Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:45.859449Z] [debug] [pid:117233] Migrating remaining bytes:   	1422069760[0m
[37m[2024-05-28T06:46:46.359946Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:46.360014Z] [debug] [pid:117233] Migrating remaining bytes:   	1407270912[0m
[37m[2024-05-28T06:46:46.860526Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:46.860587Z] [debug] [pid:117233] Migrating remaining bytes:   	1391022080[0m
[37m[2024-05-28T06:46:47.361107Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:47.361176Z] [debug] [pid:117233] Migrating remaining bytes:   	1372626944[0m
[37m[2024-05-28T06:46:47.861714Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:47.861778Z] [debug] [pid:117233] Migrating remaining bytes:   	1357635584[0m
[37m[2024-05-28T06:46:48.362489Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:48.362580Z] [debug] [pid:117233] Migrating remaining bytes:   	1342173184[0m
[37m[2024-05-28T06:46:48.863214Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:48.863302Z] [debug] [pid:117233] Migrating remaining bytes:   	1326981120[0m
[37m[2024-05-28T06:46:49.363997Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:49.364093Z] [debug] [pid:117233] Migrating remaining bytes:   	1271336960[0m
[37m[2024-05-28T06:46:49.864700Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:49.864769Z] [debug] [pid:117233] Migrating remaining bytes:   	1254510592[0m
[37m[2024-05-28T06:46:50.365595Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:50.365680Z] [debug] [pid:117233] Migrating remaining bytes:   	1238491136[0m
[37m[2024-05-28T06:46:50.866375Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:50.866453Z] [debug] [pid:117233] Migrating remaining bytes:   	1038225408[0m
[37m[2024-05-28T06:46:51.367171Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:51.367250Z] [debug] [pid:117233] Migrating remaining bytes:   	761184256[0m
[37m[2024-05-28T06:46:51.867974Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:51.868065Z] [debug] [pid:117233] Migrating remaining bytes:   	721510400[0m
[37m[2024-05-28T06:46:52.368771Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:52.368844Z] [debug] [pid:117233] Migrating remaining bytes:   	370966528[0m
[37m[2024-05-28T06:46:52.869529Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:52.869609Z] [debug] [pid:117233] Migrating remaining bytes:   	48459776[0m
[37m[2024-05-28T06:46:53.370341Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:53.370419Z] [debug] [pid:117233] Migrating remaining bytes:   	9400320[0m
[37m[2024-05-28T06:46:53.870789Z] [debug] [pid:117233] EVENT {"data":{"pass":2},"event":"MIGRATION_PASS","timestamp":{"microseconds":392229,"seconds":1716878813}}[0m
[37m[2024-05-28T06:46:53.870905Z] [debug] [pid:117233] EVENT {"data":{"pass":3},"event":"MIGRATION_PASS","timestamp":{"microseconds":426077,"seconds":1716878813}}[0m
[37m[2024-05-28T06:46:53.870981Z] [debug] [pid:117233] EVENT {"data":{"pass":4},"event":"MIGRATION_PASS","timestamp":{"microseconds":426281,"seconds":1716878813}}[0m
[37m[2024-05-28T06:46:53.871063Z] [debug] [pid:117233] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":429954,"seconds":1716878813}}[0m
[37m[2024-05-28T06:46:53.871189Z] [debug] [pid:117233] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T06:46:53.871233Z] [debug] [pid:117233] Migrating remaining bytes:   	0[0m
[37m[2024-05-28T06:46:53.871660Z] [debug] [pid:117233] Snapshot complete[0m
[37m[2024-05-28T06:46:54.165593Z] [debug] [pid:117233] EVENT {"event":"RESUME","timestamp":{"microseconds":165343,"seconds":1716878814}}[0m
[1;34m[2024-05-28T06:46:54.200340Z] [debug] [pid:117043] ||| starting boot_into_snapshot tests/installation/boot_into_snapshot.pm[0m
[37m[2024-05-28T06:46:54.203905Z] [debug] [pid:117233] QEMU: Formatting '/var/lib/openqa/pool/19/raid/hd0-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=32212254720 backing_file=/var/lib/openqa/pool/19/raid/hd0-overlay0 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[2024-05-28T06:46:54.205597Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:40 called testapi::assert_screen
[2024-05-28T06:46:54.205789Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="linux-login", timeout=200)
[32m[2024-05-28T06:46:54.260789Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found linux-login-20200525, similarity 1.00 @ 72/749[0m
[2024-05-28T06:46:54.261321Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console
[2024-05-28T06:46:54.261413Z] [debug] [pid:117043] <<< testapi::select_console(testapi_console="root-console")
[37m[2024-05-28T06:46:54.677017Z] [debug] [pid:117043] activate_console, console: root-console, type: console[0m
[2024-05-28T06:46:54.677303Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:857 called testapi::wait_still_screen
[2024-05-28T06:46:54.677449Z] [debug] [pid:117043] <<< testapi::wait_still_screen(timeout=30, stilltime=1, similarity_level=47)
[32m[2024-05-28T06:46:56.210476Z] [debug] [pid:117043] >>> testapi::wait_still_screen: detected same image for 1 seconds (1.52734303474426 s elapsed), last detected similarity is 50.4372371212676[0m
[2024-05-28T06:46:56.210648Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:862 called testapi::assert_screen
[2024-05-28T06:46:56.210813Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch=[
    "tty6-selected",
    "text-logged-in-root"
  ], timeout=60)
[32m[2024-05-28T06:46:56.325009Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found login-prompt-centos-20210810, similarity 1.00 @ 71/98[0m
[2024-05-28T06:46:56.326830Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:864 called testapi::enter_cmd
[2024-05-28T06:46:56.326977Z] [debug] [pid:117043] <<< testapi::type_string(string="root\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:46:56.495951Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:70 called testapi::assert_screen
[2024-05-28T06:46:56.496069Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="password-prompt", timeout=60)
[32m[2024-05-28T06:46:57.345570Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found password-prompt-20160812, similarity 1.00 @ 0/112[0m
[2024-05-28T06:46:57.346167Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:79 called testapi::type_password
[2024-05-28T06:46:57.346345Z] [debug] [pid:117043] <<< testapi::type_string(string="[masked]", max_interval=100, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:46:58.552923Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:81 called testapi::send_key
[2024-05-28T06:46:58.553150Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:46:58.821235Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:876 called testapi::assert_screen
[2024-05-28T06:46:58.821367Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="text-logged-in-root", timeout=60)
[37m[2024-05-28T06:46:58.838858Z] [debug] [pid:117233] no match: 59.9s, best candidate: text-logged-in-root-20170627 (0.78)[0m
[32m[2024-05-28T06:46:59.897560Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found text-logged-in-root-20151204, similarity 1.00 @ 63/160[0m
[2024-05-28T06:46:59.898379Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:879 called testapi::assert_screen
[2024-05-28T06:46:59.898522Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="root-console", timeout=30)
[32m[2024-05-28T06:47:00.911350Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 88/160[0m
[2024-05-28T06:47:00.911976Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T06:47:00.912151Z] [debug] [pid:117043] <<< testapi::type_string(string="setterm -blank 0", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:47:01.453772Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T06:47:01.453989Z] [debug] [pid:117043] <<< testapi::type_string(string="; echo YpuUt-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:47:02.568569Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T06:47:02.568809Z] [debug] [pid:117043] <<< testapi::wait_serial(regexp=qr/YpuUt-\d+-/u, expect_not_found=0, timeout=30, quiet=undef, no_regex=0, buffer_size=undef, record_output=undef)
[32m[2024-05-28T06:47:03.618267Z] [debug] [pid:117043] >>> testapi::wait_serial: (?^u:YpuUt-\d+-): ok[0m
[2024-05-28T06:47:03.618520Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:41 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T06:47:03.618630Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="root-console", timeout=30, no_wait=1)
[32m[2024-05-28T06:47:03.672732Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 88/176[0m
[2024-05-28T06:47:03.673371Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:42 called testapi::script_run
[2024-05-28T06:47:03.673496Z] [debug] [pid:117043] <<< testapi::script_run(cmd="systemctl reboot", die_on_timeout=1, output="", timeout=0, quiet=undef)
[2024-05-28T06:47:03.673594Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:42 called testapi::script_run
[2024-05-28T06:47:03.673695Z] [debug] [pid:117043] <<< testapi::type_string(string="systemctl reboot", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:47:04.214365Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:42 called testapi::script_run
[2024-05-28T06:47:04.214495Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:47:04.482991Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:44 called bootloader_setup::stop_grub_timeout -> lib/bootloader_setup.pm:82 called testapi::send_key
[2024-05-28T06:47:04.483142Z] [debug] [pid:117043] <<< testapi::send_key(key="up", wait_screen_change=0)
[2024-05-28T06:47:04.751893Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:04.752042Z] [debug] [pid:117043] <<< testapi::check_screen(mustmatch="boot-menu-snapshot", timeout=0)
[37m[2024-05-28T06:47:04.896939Z] [debug] [pid:117233] no match: -0.1s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[32m[2024-05-28T06:47:04.961593Z] [debug] [pid:117043] >>> testapi::_check_backend_response: match=boot-menu-snapshot timed out after 0 (check_screen)[0m
[2024-05-28T06:47:04.976371Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:04.976492Z] [debug] [pid:117043] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T06:47:04.977307Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:04.977383Z] [debug] [pid:117043] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T06:47:05.433305Z] [debug] [pid:117043] >>> testapi::wait_screen_change: screen change seen after 0.180164813995361 seconds (similarity: 8.52745150414149)[0m
[2024-05-28T06:47:05.433554Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:05.433780Z] [debug] [pid:117043] <<< testapi::check_screen(mustmatch="boot-menu-snapshot", timeout=5)
[37m[2024-05-28T06:47:05.780325Z] [debug] [pid:117233] no match: 4.6s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:06.768304Z] [debug] [pid:117233] no match: 3.6s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:07.755038Z] [debug] [pid:117233] no change: 2.6s[0m
[37m[2024-05-28T06:47:07.768145Z] [debug] [pid:117233] no match: 2.6s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:08.756092Z] [debug] [pid:117233] no change: 1.6s[0m
[37m[2024-05-28T06:47:08.768893Z] [debug] [pid:117233] no match: 1.6s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:09.986067Z] [debug] [pid:117233] no match: 0.6s, best candidate: boot-menu-snapshot-tw-20180316 (0.03)[0m
[37m[2024-05-28T06:47:10.983498Z] [debug] [pid:117233] no match: -0.4s, best candidate: boot-menu-snapshot-tw-20180316 (0.03)[0m
[32m[2024-05-28T06:47:11.072868Z] [debug] [pid:117043] >>> testapi::_check_backend_response: match=boot-menu-snapshot timed out after 5 (check_screen)[0m
[2024-05-28T06:47:11.086504Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:11.086620Z] [debug] [pid:117043] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T06:47:11.087145Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:11.087224Z] [debug] [pid:117043] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T06:47:11.532288Z] [debug] [pid:117043] >>> testapi::wait_screen_change: screen change seen after 0.170310020446777 seconds (similarity: 21.9720255313107)[0m
[2024-05-28T06:47:11.532781Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:11.533096Z] [debug] [pid:117043] <<< testapi::check_screen(mustmatch="boot-menu-snapshot", timeout=5)
[37m[2024-05-28T06:47:11.772720Z] [debug] [pid:117233] no match: 4.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:12.758499Z] [debug] [pid:117233] no change: 3.7s[0m
[37m[2024-05-28T06:47:12.772760Z] [debug] [pid:117233] no match: 3.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:13.759751Z] [debug] [pid:117233] no change: 2.7s[0m
[37m[2024-05-28T06:47:13.772101Z] [debug] [pid:117233] no match: 2.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:14.760703Z] [debug] [pid:117233] no change: 1.7s[0m
[37m[2024-05-28T06:47:14.778132Z] [debug] [pid:117233] no match: 1.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:16.010858Z] [debug] [pid:117233] no match: 0.7s, best candidate: boot-menu-snapshot-tw-20180316 (0.20)[0m
[37m[2024-05-28T06:47:16.987420Z] [debug] [pid:117233] no match: -0.3s, best candidate: boot-menu-snapshot-tw-20180316 (0.20)[0m
[32m[2024-05-28T06:47:17.072269Z] [debug] [pid:117043] >>> testapi::_check_backend_response: match=boot-menu-snapshot timed out after 5 (check_screen)[0m
[2024-05-28T06:47:17.086520Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:17.086645Z] [debug] [pid:117043] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T06:47:17.087238Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:17.087310Z] [debug] [pid:117043] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T06:47:17.538849Z] [debug] [pid:117043] >>> testapi::wait_screen_change: screen change seen after 0.178517818450928 seconds (similarity: 22.0042143744494)[0m
[2024-05-28T06:47:17.539050Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:306 called testapi::send_key_until_needlematch
[2024-05-28T06:47:17.539181Z] [debug] [pid:117043] <<< testapi::check_screen(mustmatch="boot-menu-snapshot", timeout=5)
[37m[2024-05-28T06:47:17.776189Z] [debug] [pid:117233] no match: 4.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:18.763885Z] [debug] [pid:117233] no change: 3.7s[0m
[37m[2024-05-28T06:47:18.777937Z] [debug] [pid:117233] no match: 3.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:19.764971Z] [debug] [pid:117233] no change: 2.7s[0m
[37m[2024-05-28T06:47:19.778975Z] [debug] [pid:117233] no match: 2.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[37m[2024-05-28T06:47:20.766038Z] [debug] [pid:117233] no change: 1.7s[0m
[37m[2024-05-28T06:47:20.777515Z] [debug] [pid:117233] no match: 1.7s, best candidate: boot-menu-snapshot-leap152-20200213 (0.00)[0m
[32m[2024-05-28T06:47:22.034559Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found boot-menu-snapshot-tw-20180316, similarity 1.00 @ 80/276[0m
[2024-05-28T06:47:22.034733Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:307 called testapi::send_key
[2024-05-28T06:47:22.034846Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:47:22.302937Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:309 called testapi::assert_screen
[2024-05-28T06:47:22.303093Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="grub2-page", timeout=60)
[37m[2024-05-28T06:47:22.792558Z] [debug] [pid:117233] no match: 59.5s, best candidate: grub2-page-20220222 (0.00)[0m
[37m[2024-05-28T06:47:23.768680Z] [debug] [pid:117233] no change: 58.5s[0m
[37m[2024-05-28T06:47:23.774116Z] [debug] [pid:117233] no match: 58.5s, best candidate: grub2-page-20220222 (0.00)[0m
[32m[2024-05-28T06:47:24.816584Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found grub2-page-20220223, similarity 1.00 @ 94/210[0m
[2024-05-28T06:47:24.855967Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:322 called testapi::send_key
[2024-05-28T06:47:24.856089Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:47:25.167782Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:45 called bootloader_setup::boot_into_snapshot -> lib/bootloader_setup.pm:325 called testapi::send_key
[2024-05-28T06:47:25.167936Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:47:25.436072Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:46 called testapi::assert_screen
[2024-05-28T06:47:25.436261Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="linux-login", timeout=200)
[37m[2024-05-28T06:47:25.793410Z] [debug] [pid:117233] no match: 199.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:26.771210Z] [debug] [pid:117233] no change: 198.6s[0m
[37m[2024-05-28T06:47:26.780849Z] [debug] [pid:117233] no match: 198.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:27.772268Z] [debug] [pid:117233] no change: 197.6s[0m
[37m[2024-05-28T06:47:27.780033Z] [debug] [pid:117233] no match: 197.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:28.772436Z] [debug] [pid:117233] no change: 196.6s[0m
[37m[2024-05-28T06:47:28.781431Z] [debug] [pid:117233] no match: 196.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:29.910846Z] [debug] [pid:117233] no match: 195.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:30.774434Z] [debug] [pid:117233] no change: 194.6s[0m
[37m[2024-05-28T06:47:30.784166Z] [debug] [pid:117233] no match: 194.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:31.775509Z] [debug] [pid:117233] no change: 193.6s[0m
[37m[2024-05-28T06:47:31.785049Z] [debug] [pid:117233] no match: 193.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:32.776419Z] [debug] [pid:117233] no change: 192.6s[0m
[37m[2024-05-28T06:47:32.786726Z] [debug] [pid:117233] no match: 192.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:33.777526Z] [debug] [pid:117233] no change: 191.6s[0m
[37m[2024-05-28T06:47:33.787970Z] [debug] [pid:117233] no match: 191.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:34.915305Z] [debug] [pid:117233] no match: 190.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:35.779534Z] [debug] [pid:117233] no change: 189.6s[0m
[37m[2024-05-28T06:47:35.789039Z] [debug] [pid:117233] no match: 189.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:36.780734Z] [debug] [pid:117233] no change: 188.6s[0m
[37m[2024-05-28T06:47:36.794194Z] [debug] [pid:117233] no match: 188.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:37.803683Z] [debug] [pid:117233] no match: 187.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:38.782730Z] [debug] [pid:117233] no change: 186.6s[0m
[37m[2024-05-28T06:47:38.798977Z] [debug] [pid:117233] no match: 186.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:39.999911Z] [debug] [pid:117233] no match: 185.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:40.784426Z] [debug] [pid:117233] no change: 184.6s[0m
[37m[2024-05-28T06:47:40.800102Z] [debug] [pid:117233] no match: 184.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:41.802107Z] [debug] [pid:117233] no match: 183.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:42.786528Z] [debug] [pid:117233] no change: 182.6s[0m
[37m[2024-05-28T06:47:42.800287Z] [debug] [pid:117233] no match: 182.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:43.787729Z] [debug] [pid:117233] no change: 181.6s[0m
[37m[2024-05-28T06:47:43.803177Z] [debug] [pid:117233] no match: 181.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:44.981319Z] [debug] [pid:117233] no match: 180.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:45.789334Z] [debug] [pid:117233] no change: 179.6s[0m
[37m[2024-05-28T06:47:45.806460Z] [debug] [pid:117233] no match: 179.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:46.799570Z] [debug] [pid:117233] no match: 178.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:47.791625Z] [debug] [pid:117233] no change: 177.6s[0m
[37m[2024-05-28T06:47:47.804178Z] [debug] [pid:117233] no match: 177.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:48.792398Z] [debug] [pid:117233] no change: 176.6s[0m
[37m[2024-05-28T06:47:48.801874Z] [debug] [pid:117233] no match: 176.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:49.951243Z] [debug] [pid:117233] no match: 175.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:50.806449Z] [debug] [pid:117233] no match: 174.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:51.795462Z] [debug] [pid:117233] no change: 173.6s[0m
[37m[2024-05-28T06:47:51.804151Z] [debug] [pid:117233] no match: 173.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:52.796425Z] [debug] [pid:117233] no change: 172.6s[0m
[37m[2024-05-28T06:47:52.806097Z] [debug] [pid:117233] no match: 172.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:53.797470Z] [debug] [pid:117233] no change: 171.6s[0m
[37m[2024-05-28T06:47:53.807044Z] [debug] [pid:117233] no match: 171.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:55.018930Z] [debug] [pid:117233] no match: 170.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:55.814930Z] [debug] [pid:117233] no match: 169.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:56.820622Z] [debug] [pid:117233] no match: 168.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:57.801532Z] [debug] [pid:117233] no change: 167.6s[0m
[37m[2024-05-28T06:47:57.821789Z] [debug] [pid:117233] no match: 167.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:47:58.802758Z] [debug] [pid:117233] no change: 166.6s[0m
[37m[2024-05-28T06:47:58.822065Z] [debug] [pid:117233] no match: 166.6s, best candidate: linux-login-20140916 (0.00)[0m
[31m[2024-05-28T06:48:01.017798Z] [warn] [pid:117233] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.21 seconds for 4 candidate needles - make your needles more specific[0m
[37m[2024-05-28T06:48:01.017880Z] [debug] [pid:117233] no match: 165.6s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:01.037754Z] [debug] [pid:117233] no match: 164.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:02.038051Z] [debug] [pid:117233] no match: 163.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:03.037444Z] [debug] [pid:117233] no match: 162.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:04.038851Z] [debug] [pid:117233] no match: 161.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:05.160144Z] [debug] [pid:117233] no match: 160.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:06.039691Z] [debug] [pid:117233] no match: 159.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:07.041826Z] [debug] [pid:117233] no match: 158.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:08.042777Z] [debug] [pid:117233] no match: 157.4s, best candidate: linux-login-20140916 (0.00)[0m
[37m[2024-05-28T06:48:09.043692Z] [debug] [pid:117233] no match: 156.4s, best candidate: linux-login-20140916 (0.00)[0m
[32m[2024-05-28T06:48:10.210947Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found linux-login-20140916, similarity 1.00 @ 80/174[0m
[2024-05-28T06:48:10.211077Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console
[2024-05-28T06:48:10.211161Z] [debug] [pid:117043] <<< testapi::select_console(testapi_console="root-console")
[37m[2024-05-28T06:48:10.618343Z] [debug] [pid:117043] activate_console, console: root-console, type: console[0m
[2024-05-28T06:48:10.618568Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:857 called testapi::wait_still_screen
[2024-05-28T06:48:10.618712Z] [debug] [pid:117043] <<< testapi::wait_still_screen(stilltime=1, similarity_level=47, timeout=30)
[32m[2024-05-28T06:48:11.688394Z] [debug] [pid:117043] >>> testapi::wait_still_screen: detected same image for 1 seconds (1.06294298171997 s elapsed), last detected similarity is 1000000[0m
[2024-05-28T06:48:11.688604Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:862 called testapi::assert_screen
[2024-05-28T06:48:11.688760Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch=[
    "tty6-selected",
    "text-logged-in-root"
  ], timeout=60)
[37m[2024-05-28T06:48:11.759950Z] [debug] [pid:117233] no match: 59.9s, best candidate: text-logged-in-root-20170321 (0.63)[0m
[37m[2024-05-28T06:48:12.755363Z] [debug] [pid:117233] no match: 58.9s, best candidate: text-logged-in-root-20170321 (0.47)[0m
[37m[2024-05-28T06:48:13.692357Z] [debug] [pid:117233] no change: 57.9s[0m
[37m[2024-05-28T06:48:13.755684Z] [debug] [pid:117233] no match: 57.9s, best candidate: text-logged-in-root-20170321 (0.47)[0m
[37m[2024-05-28T06:48:14.750259Z] [debug] [pid:117233] no match: 56.9s, best candidate: text-logged-in-root-20170321 (0.63)[0m
[32m[2024-05-28T06:48:16.166428Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found login-prompt-centos-20210810, similarity 1.00 @ 79/98[0m
[2024-05-28T06:48:16.166619Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:864 called testapi::enter_cmd
[2024-05-28T06:48:16.166760Z] [debug] [pid:117043] <<< testapi::type_string(string="root\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:48:16.336016Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:70 called testapi::assert_screen
[2024-05-28T06:48:16.336180Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="password-prompt", timeout=60)
[32m[2024-05-28T06:48:16.821823Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found password-prompt-20200507, similarity 1.00 @ 0/112[0m
[2024-05-28T06:48:16.822012Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:79 called testapi::type_password
[2024-05-28T06:48:16.822167Z] [debug] [pid:117043] <<< testapi::type_string(string="[masked]", max_interval=100, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:48:18.026892Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:81 called testapi::send_key
[2024-05-28T06:48:18.027058Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:48:18.294880Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:876 called testapi::assert_screen
[2024-05-28T06:48:18.295027Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="text-logged-in-root", timeout=60)
[37m[2024-05-28T06:48:18.305154Z] [debug] [pid:117233] no match: 59.9s, best candidate: text-logged-in-root-20170627 (0.78)[0m
[32m[2024-05-28T06:48:19.364134Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found text-logged-in-root-20151204, similarity 1.00 @ 71/160[0m
[2024-05-28T06:48:19.364328Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:879 called testapi::assert_screen
[2024-05-28T06:48:19.364444Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="root-console", timeout=30)
[32m[2024-05-28T06:48:20.365775Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 96/160[0m
[2024-05-28T06:48:20.365978Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T06:48:20.366120Z] [debug] [pid:117043] <<< testapi::type_string(string="setterm -blank 0", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:48:20.905216Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T06:48:20.905482Z] [debug] [pid:117043] <<< testapi::type_string(string="; echo YpuUt-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:48:22.018263Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T06:48:22.018495Z] [debug] [pid:117043] <<< testapi::wait_serial(buffer_size=undef, no_regex=0, record_output=undef, quiet=undef, timeout=30, regexp=qr/YpuUt-\d+-/u, expect_not_found=0)
[32m[2024-05-28T06:48:23.063789Z] [debug] [pid:117043] >>> testapi::wait_serial: (?^u:YpuUt-\d+-): ok[0m
[2024-05-28T06:48:23.064031Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:47 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T06:48:23.064149Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch="root-console", no_wait=1, timeout=30)
[32m[2024-05-28T06:48:23.115338Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 96/176[0m
[2024-05-28T06:48:23.115539Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:48 called testapi::assert_script_run
[2024-05-28T06:48:23.115688Z] [debug] [pid:117043] <<< testapi::assert_script_run(cmd="touch /etc/NOWRITE;test ! -f /etc/NOWRITE", quiet=undef, fail_message="", timeout=90)
[2024-05-28T06:48:23.115811Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:48 called testapi::assert_script_run
[2024-05-28T06:48:23.115955Z] [debug] [pid:117043] <<< testapi::type_string(string="touch /etc/NOWRITE;test ! -f /etc/NOWRITE", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:48:24.752507Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:48 called testapi::assert_script_run
[2024-05-28T06:48:24.752760Z] [debug] [pid:117043] <<< testapi::type_string(string="; echo Fs5gL-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:48:25.865520Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:48 called testapi::assert_script_run
[2024-05-28T06:48:25.865744Z] [debug] [pid:117043] <<< testapi::wait_serial(buffer_size=undef, record_output=undef, no_regex=0, quiet=undef, timeout=90, regexp=qr/Fs5gL-\d+-/u, expect_not_found=0)
[32m[2024-05-28T06:48:26.908952Z] [debug] [pid:117043] >>> testapi::wait_serial: (?^u:Fs5gL-\d+-): ok[0m
[2024-05-28T06:48:26.909125Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:49 called testapi::script_run
[2024-05-28T06:48:26.909255Z] [debug] [pid:117043] <<< testapi::script_run(cmd="systemctl reboot", quiet=undef, timeout=0, output="", die_on_timeout=1)
[2024-05-28T06:48:26.909346Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:49 called testapi::script_run
[2024-05-28T06:48:26.909448Z] [debug] [pid:117043] <<< testapi::type_string(string="systemctl reboot", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T06:48:27.451368Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:49 called testapi::script_run
[2024-05-28T06:48:27.451589Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:48:27.722084Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:51 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:902 called opensusebasetest::handle_grub -> lib/opensusebasetest.pm:687 called opensusebasetest::wait_grub -> lib/opensusebasetest.pm:439 called testapi::assert_screen
[2024-05-28T06:48:27.722301Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch=[
    "grub2"
  ], timeout=100)
[31m[2024-05-28T06:48:28.457526Z] [warn] [pid:117233] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.73 seconds for 72 candidate needles - make your needles more specific[0m
[37m[2024-05-28T06:48:28.457615Z] [debug] [pid:117233] no match: 99.9s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[37m[2024-05-28T06:48:29.191678Z] [debug] [pid:117233] no match: 98.9s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[32m[2024-05-28T06:48:30.089535Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190303, similarity 1.00 @ 11/147[0m
[2024-05-28T06:48:30.089869Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:51 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:902 called opensusebasetest::handle_grub -> lib/opensusebasetest.pm:702 called opensusebasetest::grub_select -> lib/opensusebasetest.pm:634 called testapi::send_key
[2024-05-28T06:48:30.089968Z] [debug] [pid:117043] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T06:48:30.359437Z] [debug] [pid:117043] tests/installation/boot_into_snapshot.pm:51 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:926 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:782 called opensusebasetest::wait_boot_textmode -> lib/opensusebasetest.pm:718 called testapi::assert_screen
[2024-05-28T06:48:30.359613Z] [debug] [pid:117043] <<< testapi::assert_screen(mustmatch=[
    "linux-login",
    "emergency-shell",
    "emergency-mode"
  ], timeout=500)
[37m[2024-05-28T06:48:30.815153Z] [debug] [pid:117233] no match: 499.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:31.766292Z] [debug] [pid:117233] no match: 498.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:32.726762Z] [debug] [pid:117233] no change: 497.6s[0m
[37m[2024-05-28T06:48:32.766084Z] [debug] [pid:117233] no match: 497.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:33.727844Z] [debug] [pid:117233] no change: 496.6s[0m
[37m[2024-05-28T06:48:33.766100Z] [debug] [pid:117233] no match: 496.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T06:48:35.406399Z] [warn] [pid:117233] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.68 seconds for 12 candidate needles - make your needles more specific[0m
[37m[2024-05-28T06:48:35.406486Z] [debug] [pid:117233] no match: 495.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:35.772508Z] [debug] [pid:117233] no match: 494.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:36.777518Z] [debug] [pid:117233] no match: 493.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:37.769879Z] [debug] [pid:117233] no match: 492.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:38.769234Z] [debug] [pid:117233] no match: 491.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:40.220470Z] [debug] [pid:117233] no match: 490.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:40.775077Z] [debug] [pid:117233] no match: 489.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:41.780785Z] [debug] [pid:117233] no match: 488.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:42.773693Z] [debug] [pid:117233] no match: 487.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:43.779029Z] [debug] [pid:117233] no match: 486.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T06:48:45.440919Z] [warn] [pid:117233] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 0.70 seconds for 12 candidate needles - make your needles more specific[0m
[37m[2024-05-28T06:48:45.441026Z] [debug] [pid:117233] no match: 485.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[37m[2024-05-28T06:48:45.737918Z] [debug] [pid:117233] no change: 484.6s[0m
[37m[2024-05-28T06:48:45.775605Z] [debug] [pid:117233] no match: 484.6s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[32m[2024-05-28T06:48:46.824565Z] [debug] [pid:117043] >>> testapi::_handle_found_needle: found linux-login-20200525, similarity 1.00 @ 72/749[0m
[1;34m[2024-05-28T06:48:46.831498Z] [debug] [pid:117043] ||| finished boot_into_snapshot installation (runtime: 112 s)[0m
[37m[2024-05-28T06:48:46.834292Z] [debug] [pid:116896] stopping autotest process 117043[0m
[37m[2024-05-28T06:48:46.843339Z] [debug] [pid:116896] [autotest] process exited: 0[0m
[37m[2024-05-28T06:48:46.943691Z] [debug] [pid:116896] done with autotest process[0m
[37m[2024-05-28T06:48:46.944103Z] [debug] [pid:116896] stopping command server 117033 because test execution ended[0m
[37m[2024-05-28T06:48:46.944175Z] [debug] [pid:116896] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20193/XdWpZabLnV6ZUo4b/broadcast[0m
[37m[2024-05-28T06:48:46.960036Z] [debug] [pid:116896] commands process exited: 0[0m
[37m[2024-05-28T06:48:47.060282Z] [debug] [pid:116896] done with command server[0m
[37m[2024-05-28T06:48:47.060358Z] [debug] [pid:116896] isotovideo done[0m
[37m[2024-05-28T06:48:47.060753Z] [debug] [pid:117233] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":178417,"seconds":1716878825}}[0m
[37m[2024-05-28T06:48:47.060854Z] [debug] [pid:117233] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":228207,"seconds":1716878825}}[0m
[37m[2024-05-28T06:48:47.060934Z] [debug] [pid:117233] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":254284,"seconds":1716878908}}[0m
[37m[2024-05-28T06:48:47.061018Z] [debug] [pid:117233] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":327489,"seconds":1716878908}}[0m
[37m[2024-05-28T06:48:47.061107Z] [debug] [pid:117233] QEMU status is not 'shutdown', it is 'running'[0m
[37m[2024-05-28T06:48:47.061258Z] [debug] [pid:116896] backend shutdown state: [0m
[33m[2024-05-28T06:48:47.061566Z] [info] [pid:117233] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json[0m
[37m[2024-05-28T06:48:48.122843Z] [debug] [pid:117233] Passing remaining frames to the video encoder[0m
frame=  247 fps=1.7 q=0.0 Lsize=     538kB time=00:00:10.25 bitrate= 429.8kbits/s speed=0.0716x    
video:536kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.392866%
[37m[2024-05-28T06:48:49.481378Z] [debug] [pid:117233] Waiting for video encoder to finalize the video[0m
[37m[2024-05-28T06:48:49.481474Z] [debug] [pid:117233] The built-in video encoder (pid 117426) terminated[0m
[37m[2024-05-28T06:48:49.481529Z] [debug] [pid:117233] The external video encoder (pid 117425) terminated[0m
[37m[2024-05-28T06:48:49.482062Z] [debug] [pid:117233] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 117233 (/usr/bin/isotovideo: backen)[0m
[37m[2024-05-28T06:48:49.482620Z] [debug] [pid:117233] sending magic and exit[0m
[37m[2024-05-28T06:48:49.483274Z] [debug] [pid:116896] received magic close[0m
[37m[2024-05-28T06:48:49.516339Z] [debug] [pid:116896] backend process exited: 0[0m
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x55e88fd43aa0), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
[37m[2024-05-28T06:48:49.617518Z] [debug] [pid:116896] stopping backend process 117233[0m
[37m[2024-05-28T06:48:49.617583Z] [debug] [pid:116896] done with backend process[0m
116896: EXIT 0
[2024-05-28T06:48:49.662490Z] [info] Isotovideo exit status: 0
[2024-05-28T06:48:49.684681Z] [info] +++ worker notes +++
[2024-05-28T06:48:49.684810Z] [info] End time: 2024-05-28 06:48:49
[2024-05-28T06:48:49.684882Z] [info] Result: done
[2024-05-28T06:48:49.692086Z] [info] Uploading video.webm
[2024-05-28T06:48:49.732412Z] [info] Uploading autoinst-log.txt
